/**
 * Copyright 2007-2010 Arthur Blake
 * 
 * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the
 * License. You may obtain a copy of the License at
 * 
 * http://www.apache.org/licenses/LICENSE-2.0
 * 
 * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an
 * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific
 * language governing permissions and limitations under the License.
 */
package cn.wen.log4jdbc;

import java.util.StringTokenizer;

import org.slf4j.LoggerFactory;
import org.slf4j.Logger;

/**
 * Delegates JDBC spy logging events to the the Simple Logging Facade for Java (slf4j).
 * 
 * @author Arthur Blake
 */
public class Slf4jSpyLogDelegator implements SpyLogDelegator {
    /**
     * Create a SpyLogDelegator specific to the Simple Logging Facade for Java (slf4j).
     */
    public Slf4jSpyLogDelegator() {
    }

    // logs for sql and jdbc

    /**
     * Logger that shows all JDBC calls on INFO level (exception ResultSet calls)
     */
    private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");

    /**
     * Logger that shows JDBC calls for ResultSet operations
     */
    private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");

    /**
     * Logger that shows only the SQL that is occuring
     */
    private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");

    /**
     * Logger that shows the SQL timing, post execution
     */
    private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");

    /**
     * Logger that shows connection open and close events as well as current number of open connections.
     */
    private final Logger connectionLogger = LoggerFactory.getLogger("jdbc.connection");

    // admin/setup logging for log4jdbc.

    /**
     * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
     */
    private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");

    /**
     * Determine if any of the 5 log4jdbc spy loggers are turned on (jdbc.audit | jdbc.resultset | jdbc.sqlonly | jdbc.sqltiming
     * | jdbc.connection)
     * 
     * @return true if any of the 5 spy jdbc/sql loggers are enabled at debug info or error level.
     */
    public boolean isJdbcLoggingEnabled() {
	return jdbcLogger.isErrorEnabled() || resultSetLogger.isErrorEnabled() || sqlOnlyLogger.isErrorEnabled()
		|| sqlTimingLogger.isErrorEnabled() || connectionLogger.isErrorEnabled();
    }

    /**
     * Called when a jdbc method throws an Exception.
     * 
     * @param spy the Spy wrapping the class that threw an Exception.
     * @param methodCall a description of the name and call parameters of the method generated the Exception.
     * @param e the Exception that was thrown.
     * @param sql optional sql that occured just before the exception occured.
     * @param execTime optional amount of time that passed before an exception was thrown when sql was being executed. caller
     *            should pass -1 if not used
     */
    public void exceptionOccured(Spy spy, String methodCall, Exception e, String sql, long execTime) {
	String classType = spy.getClassType();
	Integer spyNo = spy.getConnectionNumber();
	String header = spyNo + ". " + classType + "." + methodCall;
	if (sql == null) {
	    jdbcLogger.error(header, e);
	    sqlOnlyLogger.error(header, e);
	    sqlTimingLogger.error(header, e);
	}
	else {
	    jdbcLogger.error(header + " " + sql, e);

	    // if at debug level, display debug info to error log
	    if (sqlOnlyLogger.isDebugEnabled()) {
		sqlOnlyLogger.error(getDebugInfo() + nl + spyNo + ". " + sql, e);
	    }
	    else {
		sqlOnlyLogger.error(header + " " + sql, e);
	    }

	    // if at debug level, display debug info to error log
	    if (sqlTimingLogger.isDebugEnabled()) {
		sqlTimingLogger.error(getDebugInfo() + nl + spyNo + ". " + sql + " {FAILED after " + execTime + " msec}", e);
	    }
	    else {
		sqlTimingLogger.error(header + " FAILED! " + sql + " {FAILED after " + execTime + " msec}", e);
	    }
	}
    }

    /**
     * Called when a JDBC method from a Connection, Statement, PreparedStatement, CallableStatement or ResultSet returns.
     * 
     * @param spy the Spy wrapping the class that called the method that returned.
     * @param methodCall a description of the name and call parameters of the method that returned.
     * @param returnMsg return value converted to a String for integral types, or String representation for Object. Return types
     *            this will be null for void return types.
     */
    public void methodReturned(Spy spy, String methodCall, String returnMsg) {
	String classType = spy.getClassType();
	Logger logger = ResultSetSpy.classTypeDescription.equals(classType) ? resultSetLogger : jdbcLogger;
	if (logger.isInfoEnabled()) {
	    String header = spy.getConnectionNumber() + ". " + classType + "." + methodCall + " returned " + returnMsg;
	    if (logger.isDebugEnabled()) {
		logger.debug(header + " " + getDebugInfo());
	    }
	    else {
		logger.info(header);
	    }
	}
    }

    /**
     * Called when a spied upon object is constructed.
     * 
     * @param spy the Spy wrapping the class that called the method that returned.
     * @param constructionInfo information about the object construction
     */
    public void constructorReturned(Spy spy, String constructionInfo) {
	// not used in this implementation -- yet
    }

    private static String nl = System.getProperty("line.separator");

    /**
     * Determine if the given sql should be logged or not based on the various DumpSqlXXXXXX flags.
     * 
     * @param sql SQL to test.
     * @return true if the SQL should be logged, false if not.
     */
    private boolean shouldSqlBeLogged(String sql) {
	if (sql == null) {
	    return false;
	}
	sql = sql.trim();

	if (sql.length() < 6) {
	    return false;
	}
	sql = sql.substring(0, 6).toLowerCase();
	return (DriverSpy.DumpSqlSelect && "select".equals(sql)) || (DriverSpy.DumpSqlInsert && "insert".equals(sql))
		|| (DriverSpy.DumpSqlUpdate && "update".equals(sql)) || (DriverSpy.DumpSqlDelete && "delete".equals(sql))
		|| (DriverSpy.DumpSqlCreate && "create".equals(sql));
    }

    /**
     * Special call that is called only for JDBC method calls that contain SQL.
     * 
     * @param spy the Spy wrapping the class where the SQL occured.
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * @param sql sql that occured.
     */
    public void sqlOccured(Spy spy, String methodCall, String sql) {
	if (sql.contains("/*no-output*/")) return;
	
	if (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql)) {
	    sql = processSql(sql);

	    if (sqlOnlyLogger.isDebugEnabled()) {
		sqlOnlyLogger.debug(getDebugInfo() + nl + spy.getConnectionNumber() + ". " + sql);
	    }
	    else if (sqlOnlyLogger.isInfoEnabled()) {
		sqlOnlyLogger.info(sql);
	    }
	}
    }

    /**
     * Break an SQL statement up into multiple lines in an attempt to make it more readable
     * 
     * @param sql SQL to break up.
     * @return SQL broken up into multiple lines
     */
    private String processSql(String sql) {
	if (sql == null) {
	    return null;
	}

	if (DriverSpy.TrimSql) {
	    sql = sql.trim();
	}

	StringBuffer output = new StringBuffer();

	if (DriverSpy.DumpSqlMaxLineLength <= 0) {
	    output.append(sql);
	}
	else {
	    // insert line breaks into sql to make it more readable
	    StringTokenizer st = new StringTokenizer(sql);
	    String token;
	    int linelength = 0;

	    while (st.hasMoreElements()) {
		token = (String) st.nextElement();

		output.append(token);
		linelength += token.length();
		output.append(" ");
		linelength++;
		if (linelength > DriverSpy.DumpSqlMaxLineLength) {
		    output.append("\n");
		    linelength = 0;
		}
	    }
	}

	if (DriverSpy.DumpSqlAddSemicolon) {
	    output.append(";");
	}

	return output.toString();
    }

    /**
     * Special call that is called only for JDBC method calls that contain SQL.
     * 
     * @param spy the Spy wrapping the class where the SQL occurred.
     * @param execTime how long it took the SQL to run, in milliseconds.
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * @param sql SQL that occurred.
     */
    public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql) {
	if (sql.contains("/*no-output*/")) return;
	
	if (sqlTimingLogger.isErrorEnabled() && (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql))) {

	    if (DriverSpy.SqlTimingErrorThresholdEnabled && execTime >= DriverSpy.SqlTimingErrorThresholdMsec) {

		sqlTimingLogger.error(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
	    }
	    else if (sqlTimingLogger.isWarnEnabled()) {

		if (DriverSpy.SqlTimingWarnThresholdEnabled && execTime >= DriverSpy.SqlTimingWarnThresholdMsec) {

		    sqlTimingLogger.warn(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
		}
		else if (sqlTimingLogger.isDebugEnabled()) {

		    sqlTimingLogger.debug(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
		}
		else if (sqlTimingLogger.isInfoEnabled()) {

		    sqlTimingLogger.info(buildSqlTimingDump(spy, execTime, methodCall, sql, false));
		}
	    }
	}
    }

    /**
     * Helper method to quickly build a SQL timing dump output String for logging.
     * 
     * @param spy the Spy wrapping the class where the SQL occurred.
     * 
     * @param execTime how long it took the SQL to run, in milliseconds.
     * 
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * 
     * @param sql SQL that occurred.
     * 
     * @param debugInfo if true, include debug info at the front of the output.
     * 
     * @return a SQL timing dump String for logging.
     */
    private String buildSqlTimingDump(Spy spy, long execTime, String methodCall, String sql, boolean debugInfo) {
	StringBuffer out = new StringBuffer();

	if (debugInfo) {
	    out.append(getDebugInfo());
	    out.append(nl);
	    out.append(spy.getConnectionNumber());
	    out.append(". ");
	}

	// NOTE: if both sql dump and sql timing dump are on, the processSql
	// algorithm will run TWICE once at the beginning and once at the end
	// this is not very efficient but usually
	// only one or the other dump should be on and not both.

	sql = processSql(sql);

	out.append(sql);
	out.append(" {executed in ");
	out.append(execTime);
	out.append(" msec}");

	return out.toString();
    }

    /**
     * Get debugging info - the module and line number that called the logger version that prints the stack trace information
     * from the point just before we got it (cn.wen.log4jdbc)
     * 
     * if the optional log4jdbc.debug.stack.prefix system property is defined then the last call point from an application is
     * shown in the debug trace output, instead of the last direct caller into log4jdbc
     * 
     * @return debugging info for whoever called into JDBC from within the application.
     */
    private static String getDebugInfo() {
	Throwable t = new Throwable();
	t.fillInStackTrace();

	StackTraceElement[] stackTrace = t.getStackTrace();

	if (stackTrace != null) {
	    String className;

	    StringBuffer dump = new StringBuffer();

	    /**
	     * The DumpFullDebugStackTrace option is useful in some situations when we want to see the full stack trace in the
	     * debug info- watch out though as this will make the logs HUGE!
	     */
	    if (DriverSpy.DumpFullDebugStackTrace) {
		boolean first = true;
		for (int i = 0; i < stackTrace.length; i++) {
		    className = stackTrace[i].getClassName();
		    if (!className.startsWith("cn.wen.log4jdbc")) {
			if (first) {
			    first = false;
			}
			else {
			    dump.append("  ");
			}
			dump.append("at ");
			dump.append(stackTrace[i]);
			dump.append(nl);
		    }
		}
	    }
	    else {
		dump.append(" ");
		int firstLog4jdbcCall = 0;
		int lastApplicationCall = 0;

		for (int i = 0; i < stackTrace.length; i++) {
		    className = stackTrace[i].getClassName();
		    if (className.startsWith("cn.wen.log4jdbc")) {
			firstLog4jdbcCall = i;
		    }
		    else if (DriverSpy.TraceFromApplication && className.startsWith(DriverSpy.DebugStackPrefix)) {
			lastApplicationCall = i;
			break;
		    }
		}
		int j = lastApplicationCall;

		if (j == 0) // if app not found, then use whoever was the last guy that called a log4jdbc class.
		{
		    j = 1 + firstLog4jdbcCall;
		}

		dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(")
			.append(stackTrace[j].getFileName()).append(":").append(stackTrace[j].getLineNumber()).append(")");
	    }

	    return dump.toString();
	}
	else {
	    return null;
	}
    }

    /**
     * Log a Setup and/or administrative log message for log4jdbc.
     * 
     * @param msg message to log.
     */
    public void debug(String msg) {
	debugLogger.debug(msg);
    }

    /**
     * Called whenever a new connection spy is created.
     * 
     * @param spy ConnectionSpy that was created.
     */
    public void connectionOpened(Spy spy) {
	if (connectionLogger.isDebugEnabled()) {
	    connectionLogger.info(spy.getConnectionNumber() + ". Connection opened " + getDebugInfo());
	    connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
	}
	else {
	    connectionLogger.info(spy.getConnectionNumber() + ". Connection opened");
	}
    }

    /**
     * Called whenever a connection spy is closed.
     * 
     * @param spy ConnectionSpy that was closed.
     */
    public void connectionClosed(Spy spy) {
	if (connectionLogger.isDebugEnabled()) {
	    connectionLogger.info(spy.getConnectionNumber() + ". Connection closed " + getDebugInfo());
	    connectionLogger.debug(ConnectionSpy.getOpenConnectionsDump());
	}
	else {
	    connectionLogger.info(spy.getConnectionNumber() + ". Connection closed");
	}
    }
}
